**** dT 0.000 * top TEST ../../../../bin/varnishtest/tests/d00007.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest **** top extmacro def date(...) **** top extmacro def string(...) **** top extmacro def localhost=127.0.0.1 **** top extmacro def bad_backend=127.0.0.1:39075 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** top extmacro def topbuild=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub **** top extmacro def topsrc=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/../.. **** top macro def testdir=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests **** top macro def tmpdir=/home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2 **** top macro def vtcid=vtc.2687366.5660aeb2 ** top === varnishtest "Test dynamic backends" * top VTEST Test dynamic backends ** top === varnish v2 -proto PROXY -vcl { **** dT 0.012 ** v2 Launch *** v2 CMD: cd ${pwd} && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v2 -i v2 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0',PROXY -M '127.0.0.1 39509' -P /home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v2/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs *** v2 CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v2 -i v2 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0',PROXY -M '127.0.0.1 39509' -P /home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v2/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs *** v2 PID: 2687384 **** v2 macro def v2_pid=2687384 **** v2 macro def v2_name=/home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v2 **** dT 0.018 *** v2 debug|Info: Working directory not mounted on tmpfs partition *** v2 debug| **** dT 0.031 *** v2 debug|Debug: Version: varnish-trunk revision 53f14d83b39cf2dd33f521bb403a92d0423082e3 *** v2 debug|Debug: Platform: Linux,4.18.0-553.37.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit *** v2 debug|200 329 *** v2 debug|----------------------------- *** v2 debug|Varnish Cache CLI 1.0 *** v2 debug|----------------------------- *** v2 debug|Linux,4.18.0-553.37.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit *** v2 debug|varnish-trunk revision 53f14d83b39cf2dd33f521bb403a92d0423082e3 *** v2 debug| *** v2 debug|Type 'help' for command list. *** v2 debug|Type 'quit' to close CLI session. *** v2 debug|Type 'start' to launch worker process. *** v2 debug| **** dT 0.128 **** v2 CLIPOLL 1 0x1 0x0 0x0 *** v2 CLI connection fd = 5 *** v2 CLI RX 107 **** v2 CLI RX|mwtbcjunvynvxhtrorbtdzfmuzlspvju **** v2 CLI RX| **** v2 CLI RX|Authentication required. **** v2 CLI TX|auth 89c1b60a02baec29340813548e93e0e1718052258ce08d27a1042268dc85ee2f **** dT 0.133 *** v2 CLI RX 200 **** v2 CLI RX|----------------------------- **** v2 CLI RX|Varnish Cache CLI 1.0 **** v2 CLI RX|----------------------------- **** v2 CLI RX|Linux,4.18.0-553.37.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit **** v2 CLI RX|varnish-trunk revision 53f14d83b39cf2dd33f521bb403a92d0423082e3 **** v2 CLI RX| **** v2 CLI RX|Type 'help' for command list. **** v2 CLI RX|Type 'quit' to close CLI session. **** v2 CLI RX|Type 'start' to launch worker process. **** v2 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v2 CLI TX|vcl 4.1; **** v2 CLI TX| **** v2 CLI TX|\timport debug; **** v2 CLI TX|\timport std; **** v2 CLI TX|\timport proxy; **** v2 CLI TX| **** v2 CLI TX|\tbackend dummy { .host = "127.0.0.1:39075"; } **** v2 CLI TX| **** v2 CLI TX|\tsub vcl_init { **** v2 CLI TX|\t\tnew s1 = debug.dyn("0.0.0.0", "0"); **** v2 CLI TX|\t} **** v2 CLI TX| **** v2 CLI TX|\tsub vcl_recv { **** v2 CLI TX|\t\ts1.refresh(server.ip, std.port(server.ip)); **** v2 CLI TX|\t\tset req.backend_hint = s1.backend(); **** v2 CLI TX|\t\tset req.http.Authority = proxy.authority(); **** v2 CLI TX|\t\treturn (pass); **** v2 CLI TX|\t} **** v2 CLI TX| **** v2 CLI TX|\tsub vcl_deliver { **** v2 CLI TX|\t\tset resp.http.Authority = req.http.Authority; **** v2 CLI TX|\t} **** v2 CLI TX| **** v2 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.237 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 0.338 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 0.439 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 0.540 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 0.643 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 0.744 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 0.848 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 0.950 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 1.052 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 1.157 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 1.257 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 1.279 *** v2 CLI RX 200 **** v2 CLI RX|VCL compiled. **** v2 CLI TX|vcl.use vcl1 **** dT 1.281 *** v2 CLI RX 200 **** v2 CLI RX|VCL 'vcl1' now active ** v2 Start **** v2 CLI TX|start **** dT 1.360 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 1.377 *** v2 debug|Debug: Child (2687397) Started **** dT 1.461 *** v2 vsl|No VSL chunk found (child not started ?) **** dT 1.577 *** v2 debug|Child launched OK **** dT 1.595 *** v2 debug|Info: Child (2687397) said Child starts **** dT 1.596 *** v2 CLI RX 200 *** v2 wait-running **** v2 CLI TX|status **** dT 1.601 *** v2 CLI RX 200 **** v2 CLI RX|Child in state running **** v2 CLI TX|debug.listen_address **** dT 1.655 *** v2 CLI RX 200 **** v2 CLI RX|a0 127.0.0.1 42283 **** v2 CLI TX|debug.xid 1000 **** dT 1.668 **** v2 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1739980594.005125/vgc.so 1auto **** v2 vsl| 0 Debug - vcl1: VCL_EVENT_WARM **** v2 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1739980594.005125/vgc.so" as "vcl1" **** v2 vsl| 0 CLI - Rd vcl.use "vcl1" **** v2 vsl| 0 CLI - Wr 200 0 **** v2 vsl| 0 CLI - Rd start **** v2 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:42283 **** v2 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:42283 **** v2 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:42283 **** v2 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:42283 **** v2 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:42283 **** v2 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:42283 **** v2 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:42283 **** v2 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:42283 **** v2 vsl| 0 CLI - Wr 200 0 **** v2 vsl| 0 CLI - Rd debug.listen_address **** v2 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 42283 **** dT 1.711 *** v2 CLI RX 200 **** v2 CLI RX|XID is 1000 chunk 1 **** v2 CLI TX|debug.listen_address **** dT 1.769 *** v2 CLI RX 200 **** v2 CLI RX|a0 127.0.0.1 42283 ** v2 Listen on 127.0.0.1 42283 **** v2 macro def v2_addr=127.0.0.1 **** v2 macro def v2_port=42283 **** v2 macro def v2_sock=127.0.0.1:42283 **** v2 macro def v2_a0_addr=127.0.0.1 **** v2 macro def v2_a0_port=42283 **** v2 macro def v2_a0_sock=127.0.0.1:42283 ** top === server s1 { ** s1 Starting server **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=45247 **** s1 macro def s1_sock=127.0.0.1:45247 * s1 Listen on 127.0.0.1:45247 ** top === varnish v1 -vcl { **** dT 1.773 **** v2 vsl| 0 CLI - Rd debug.xid 1000 **** v2 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** v2 vsl| 0 CLI - Rd debug.listen_address **** v2 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 42283 ** s1 Started on 127.0.0.1:45247 (1 iterations) **** dT 1.791 ** v1 Launch *** v1 CMD: cd ${pwd} && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 35143' -P /home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs *** v1 CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd -d -n /home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 35143' -P /home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs *** v1 PID: 2687437 **** v1 macro def v1_pid=2687437 **** v1 macro def v1_name=/home/linux1/VT/_vtest_tmp/vtc.2687366.5660aeb2/v1 **** dT 1.799 *** v1 debug|Info: Working directory not mounted on tmpfs partition *** v1 debug| **** dT 1.810 *** v1 debug|Debug: Version: varnish-trunk revision 53f14d83b39cf2dd33f521bb403a92d0423082e3 *** v1 debug|Debug: Platform: Linux,4.18.0-553.37.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit *** v1 debug|200 329 *** v1 debug|----------------------------- *** v1 debug|Varnish Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|Linux,4.18.0-553.37.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit *** v1 debug|varnish-trunk revision 53f14d83b39cf2dd33f521bb403a92d0423082e3 *** v1 debug| *** v1 debug|Type 'help' for command list. *** v1 debug|Type 'quit' to close CLI session. *** v1 debug|Type 'start' to launch worker process. *** v1 debug| **** dT 1.906 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 18 *** v1 CLI RX 107 **** v1 CLI RX|kaqieqalbvmgtoitenwsteafjyzegeej **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth 70fddcf08dd9d61ab4492df4ae14a32aa0705cff968f323b33d6f31fe2b5d718 **** dT 1.911 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Varnish Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Linux,4.18.0-553.37.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|varnish-trunk revision 53f14d83b39cf2dd33f521bb403a92d0423082e3 **** v1 CLI RX| **** v1 CLI RX|Type 'help' for command list. **** v1 CLI RX|Type 'quit' to close CLI session. **** v1 CLI RX|Type 'start' to launch worker process. **** dT 1.912 **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\timport vtc; **** v1 CLI TX| **** v1 CLI TX|\tbackend dummy { .host = "127.0.0.1:39075"; } **** v1 CLI TX| **** v1 CLI TX|\tprobe p1 { **** v1 CLI TX|\t\t.threshold = 8; **** v1 CLI TX|\t\t.initial = 8; **** v1 CLI TX|\t\t.interval = 1m; **** v1 CLI TX|\t\t.request = **** v1 CLI TX|\t\t\t"GET / HTTP/1.1" **** v1 CLI TX|\t\t\t"Host: 127.0.0.1" **** v1 CLI TX|\t\t\t"Probe: p1" **** v1 CLI TX|\t\t\t"Connection: close"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|\tprobe p2 { **** v1 CLI TX|\t\t.threshold = 8; **** v1 CLI TX|\t\t.initial = 8; **** v1 CLI TX|\t\t.interval = 1m; **** v1 CLI TX|\t\t.request = **** v1 CLI TX|\t\t\t"GET / HTTP/1.1" **** v1 CLI TX|\t\t\t"Host: 127.0.0.1" **** v1 CLI TX|\t\t\t"Probe: p2" **** v1 CLI TX|\t\t\t"Connection: close"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|\tbackend v2 { .host = "127.0.0.1"; .port = "42283"; } **** v1 CLI TX| **** v1 CLI TX|\tsub vcl_init { **** v1 CLI TX|\t\tnew s1 = debug.dyn("0.0.0.0", "0"); **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|\tsub vcl_recv { **** v1 CLI TX|\t\tif (req.url == "/1") { **** v1 CLI TX|\t\t\ts1.refresh("127.0.0.1", "45247", p1); **** v1 CLI TX|\t\t\tvtc.sleep(1s); **** v1 CLI TX|\t\t} else if (req.url == "/2") { **** v1 CLI TX|\t\t\ts1.refresh("127.0.0.1", "45247", p2, **** v1 CLI TX|\t\t\t via=v2); **** v1 CLI TX|\t\t\tvtc.sleep(1s); **** v1 CLI TX|\t\t} **** v1 CLI TX|\t\tset req.backend_hint = s1.backend(); **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 2.014 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.116 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.216 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.316 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.418 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.521 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.622 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.727 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.830 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 2.931 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.031 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.131 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.231 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.332 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.442 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.542 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.642 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.743 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.845 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 3.945 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.005 *** v1 CLI RX 200 **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 **** dT 4.010 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 4.049 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.060 *** v1 debug|Debug: Child (2687450) Started **** dT 4.150 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 4.248 *** v1 debug|Child launched OK **** dT 4.252 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1739980595.783458/vgc.so 1auto **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1739980595.783458/vgc.so" as "vcl1" **** dT 4.264 *** v1 debug|Info: Child (2687450) said Child starts **** dT 4.275 *** v1 CLI RX 200 *** v1 wait-running **** v1 CLI TX|status **** dT 4.280 *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address **** dT 4.352 *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 38809 **** v1 CLI TX|debug.xid 1000 **** v1 vsl| 0 CLI - Rd vcl.use "vcl1" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd start **** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:38809 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:38809 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:38809 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:38809 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:38809 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:38809 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:38809 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:38809 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 38809 **** dT 4.413 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address **** dT 4.456 **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** dT 4.474 *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 38809 ** v1 Listen on 127.0.0.1 38809 **** v1 macro def v1_addr=127.0.0.1 **** v1 macro def v1_port=38809 **** v1 macro def v1_sock=127.0.0.1:38809 **** v1 macro def v1_a0_addr=127.0.0.1 **** v1 macro def v1_a0_port=38809 **** v1 macro def v1_a0_sock=127.0.0.1:38809 ** top === varnish v1 -expect MAIN.n_backend == 3 **** dT 4.475 ** v1 as expected: MAIN.n_backend (3) == 3 (3) ** top === client c1 { ** c1 Starting client ** c1 Waiting for client ** c1 Started on 127.0.0.1:38809 (1 iterations) *** c1 Connect to 127.0.0.1:38809 *** c1 connected fd 30 from 127.0.0.1 49514 to 127.0.0.1:38809 ** c1 === txreq -url /1 **** c1 txreq|GET /1 HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === rxresp **** dT 4.486 *** s1 accepted fd 16 127.0.0.1 45812 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|Probe: p1\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 65 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |Probe: p1 **** s1 http[ 5] |Connection: close **** s1 bodylen = 0 ** s1 === expect req.url == "/" **** s1 EXPECT req.url (/) == "/" match ** s1 === expect req.http.Probe == "p1" **** s1 EXPECT req.http.Probe (p1) == "p1" match ** s1 === expect req.http.Authority == **** s1 EXPECT req.http.Authority () == "" match ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Wed, 19 Feb 2025 15:56:38 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === close **** s1 Closed ** s1 === accept **** s1 Accepting **** dT 4.558 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 38809 **** v1 vsl| 1000 Begin c sess 0 HTTP/1 **** v1 vsl| 1000 SessOpen c 127.0.0.1 49514 a0 127.0.0.1 38809 1739980598.346874 23 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:38809 **** v1 vsl| 1000 Debug c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:38809 **** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:38809 **** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:38809 **** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:38809 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:38809 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:38809 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:38809 **** v1 vsl| 1000 Link c req 1001 rxreq **** v1 vsl| 0 Backend_health - s1 Still healthy -------H 8 8 9 0.000000 0.000000 "" **** v1 vsl| 0 Backend_health - s1 Still healthy -------H 8 8 9 0.000000 0.000000 "" **** v1 vsl| 0 Backend_health - s1 Still healthy 4---X-RH 9 8 9 0.005067 0.001267 "HTTP/1.1 200 OK" **** dT 4.728 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980598 1.0 **** dT 5.486 *** s1 Accepted socket fd is 16 ** s1 === rxreq **** s1 rxhdr|GET /1 HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1002\r **** s1 rxhdr|\r **** s1 rxhdrlen = 149 **** s1 http[ 0] |GET **** s1 http[ 1] |/1 **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |User-Agent: c1 **** s1 http[ 5] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 6] |Via: 1.1 v1 (Varnish/trunk) **** s1 http[ 7] |Accept-Encoding: gzip **** s1 http[ 8] |X-Varnish: 1002 **** s1 bodylen = 0 ** s1 === expect req.url == "/1" **** s1 EXPECT req.url (/1) == "/1" match ** s1 === expect req.http.Probe == **** s1 EXPECT req.http.Probe () == "" match ** s1 === expect req.http.Authority == **** s1 EXPECT req.http.Authority () == "" match ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Wed, 19 Feb 2025 15:56:39 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === close **** s1 Closed ** s1 === accept **** s1 Accepting **** dT 5.506 **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|Date: Wed, 19 Feb 2025 15:56:39 GMT\r **** c1 rxhdr|Server: s1\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|X-Varnish: 1001\r **** c1 rxhdr|Age: 0\r **** c1 rxhdr|Via: 1.1 v1 (Varnish/trunk)\r **** c1 rxhdr|Accept-Ranges: bytes\r **** c1 rxhdr|Connection: keep-alive\r **** c1 rxhdr|\r **** c1 rxhdrlen = 187 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |200 **** c1 http[ 2] |OK **** c1 http[ 3] |Date: Wed, 19 Feb 2025 15:56:39 GMT **** c1 http[ 4] |Server: s1 **** c1 http[ 5] |Content-Length: 0 **** c1 http[ 6] |X-Varnish: 1001 **** c1 http[ 7] |Age: 0 **** c1 http[ 8] |Via: 1.1 v1 (Varnish/trunk) **** c1 http[ 9] |Accept-Ranges: bytes **** c1 http[10] |Connection: keep-alive **** c1 bodylen = 0 ** c1 === expect resp.status == 200 **** c1 EXPECT resp.status (200) == "200" match ** c1 === expect resp.http.Authority == **** c1 EXPECT resp.http.Authority () == "" match ** c1 === txreq -url /2 **** c1 txreq|GET /2 HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === rxresp **** dT 5.586 **** v1 vsl| 1002 Begin b bereq 1001 fetch **** v1 vsl| 1002 VCL_use b vcl1 **** v1 vsl| 1002 Timestamp b Start: 1739980599.352592 0.000000 0.000000 **** v1 vsl| 1002 BereqMethod b GET **** v1 vsl| 1002 BereqURL b /1 **** v1 vsl| 1002 BereqProtocol b HTTP/1.1 **** v1 vsl| 1002 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1002 BereqHeader b User-Agent: c1 **** v1 vsl| 1002 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1002 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1002 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1002 BereqHeader b X-Varnish: 1002 **** v1 vsl| 1002 VCL_call b BACKEND_FETCH **** v1 vsl| 1002 VCL_return b fetch **** v1 vsl| 1002 Timestamp b Fetch: 1739980599.352624 0.000031 0.000031 **** v1 vsl| 1002 Timestamp b Connected: 1739980599.352789 0.000196 0.000164 **** v1 vsl| 1002 BackendOpen b 26 s1 127.0.0.1 45247 127.0.0.1 45818 connect **** v1 vsl| 1002 Timestamp b Bereq: 1739980599.352830 0.000237 0.000041 **** v1 vsl| 1002 BerespProtocol b HTTP/1.1 **** v1 vsl| 1002 BerespStatus b 200 **** v1 vsl| 1002 BerespReason b OK **** v1 vsl| 1002 BerespHeader b Date: Wed, 19 Feb 2025 15:56:39 GMT **** v1 vsl| 1002 BerespHeader b Server: s1 **** v1 vsl| 1002 BerespHeader b Content-Length: 0 **** v1 vsl| 1002 Timestamp b Beresp: 1739980599.357970 0.005378 0.005140 **** v1 vsl| 1002 TTL b RFC 120 10 0 1739980599 1739980599 1739980599 0 0 cacheable **** v1 vsl| 1002 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1002 VCL_return b deliver **** v1 vsl| 1002 Timestamp b Process: 1739980599.358001 0.005408 0.000030 **** v1 vsl| 1002 Filters b **** v1 vsl| 1002 Storage b malloc s0 **** v1 vsl| 1002 Fetch_Body b 0 none - **** v1 vsl| 1002 BackendClose b 26 s1 recycle **** v1 vsl| 1002 Timestamp b BerespBody: 1739980599.368870 0.016277 0.010869 **** v1 vsl| 1002 Length b 0 **** v1 vsl| 1002 BereqAcct b 149 0 149 87 0 87 **** v1 vsl| 1002 End b **** v1 vsl| 1001 Begin c req 1000 rxreq **** v1 vsl| 1001 Timestamp c Start: 1739980598.346922 0.000000 0.000000 **** v1 vsl| 1001 Timestamp c Req: 1739980598.346922 0.000000 0.000000 **** v1 vsl| 1001 VCL_use c vcl1 **** v1 vsl| 1001 ReqStart c 127.0.0.1 49514 a0 **** v1 vsl| 1001 ReqMethod c GET **** v1 vsl| 1001 ReqURL c /1 **** v1 vsl| 1001 ReqProtocol c HTTP/1.1 **** v1 vsl| 1001 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1001 ReqHeader c User-Agent: c1 **** v1 vsl| 1001 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1001 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1001 VCL_call c RECV **** v1 vsl| 1001 VCL_return c hash **** v1 vsl| 1001 VCL_call c HASH **** v1 vsl| 1001 VCL_return c lookup **** v1 vsl| 1001 VCL_call c MISS **** v1 vsl| 1001 VCL_return c fetch **** v1 vsl| 1001 Link c bereq 1002 fetch **** v1 vsl| 1001 Timestamp c Fetch: 1739980599.372141 1.025218 1.025218 **** v1 vsl| 1001 RespProtocol c HTTP/1.1 **** v1 vsl| 1001 RespStatus c 200 **** v1 vsl| 1001 RespReason c OK **** v1 vsl| 1001 RespHeader c Date: Wed, 19 Feb 2025 15:56:39 GMT **** v1 vsl| 1001 RespHeader c Server: s1 **** v1 vsl| 1001 RespHeader c Content-Length: 0 **** v1 vsl| 1001 RespHeader c X-Varnish: 1001 **** v1 vsl| 1001 RespHeader c Age: 0 **** v1 vsl| 1001 RespHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1001 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1001 VCL_call c DELIVER **** v1 vsl| 1001 VCL_return c deliver **** v1 vsl| 1001 Timestamp c Process: 1739980599.372174 1.025251 0.000032 **** v1 vsl| 1001 Filters c **** v1 vsl| 1001 RespHeader c Connection: keep-alive **** v1 vsl| 1001 Timestamp c Resp: 1739980599.372223 1.025301 0.000049 **** v1 vsl| 1001 ReqAcct c 52 0 52 187 0 187 **** v1 vsl| 1001 End c **** v1 vsl| 1000 Link c req 1003 rxreq **** v1 vsl| 0 Backend_health - s1 Still healthy -------H 8 8 9 0.000000 0.000000 "" **** v1 vsl| 0 Backend_health - s1 Still healthy -------H 8 8 9 0.000000 0.000000 "" **** v1 vsl| 0 Backend_health - s1 Still healthy -------H 8 8 9 0.000000 0.000000 "" **** dT 6.547 *** s1 Accepted socket fd is 16 ** s1 === rxreq **** s1 rxhdr|GET /2 HTTP/1.1\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Varnish: 1004\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1, 0.0.0.0\r **** s1 rxhdr|Via: 1.1 v1 (Varnish/trunk), 1.1 v2 (Varnish/trunk)\r **** s1 rxhdr|Authority: 127.0.0.1\r **** s1 rxhdr|X-Varnish: 1002\r **** s1 rxhdr|\r **** s1 rxhdrlen = 221 **** s1 http[ 0] |GET **** s1 http[ 1] |/2 **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: 127.0.0.1 **** s1 http[ 4] |User-Agent: c1 **** s1 http[ 5] |Accept-Encoding: gzip **** s1 http[ 6] |X-Varnish: 1004 **** s1 http[ 7] |X-Forwarded-For: 127.0.0.1, 0.0.0.0 **** s1 http[ 8] |Via: 1.1 v1 (Varnish/trunk), 1.1 v2 (Varnish/trunk) **** s1 http[ 9] |Authority: 127.0.0.1 **** s1 http[10] |X-Varnish: 1002 **** s1 bodylen = 0 ** s1 === expect req.url == "/" ---- s1 EXPECT req.url (/2) == "/" failed **** dT 6.580 **** v2 vsl| 1000 Begin c sess 0 PROXY **** v2 vsl| 1000 SessOpen c 127.0.0.1 50518 a0 127.0.0.1 42283 1739980600.385566 23 **** v2 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1000 Debug c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1000 Proxy c 2 0.0.0.0 0 127.0.0.1 45247 **** v2 vsl| 1000 Link c req 1001 rxreq **** v2 vsl| 1003 Begin c sess 0 PROXY **** v2 vsl| 1003 SessOpen c 127.0.0.1 50532 a0 127.0.0.1 42283 1739980600.417137 24 **** v2 vsl| 1003 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1003 Debug c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1003 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1003 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1003 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1003 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1003 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1003 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:42283 **** v2 vsl| 1003 Proxy c 2 0.0.0.0 0 127.0.0.1 45247 **** v2 vsl| 1003 Link c req 1004 rxreq **** dT 7.312 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980601 1.0 **** dT 7.700 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980601 1.0 **** dT 8.639 **** v1 vsl| 0 Backend_health - s1 Still healthy 4---Xr-- 8 8 9 0.000000 0.000000 "Poll error 110 (Connection timed out)" **** dT 10.265 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980604 1.0 **** dT 10.746 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980604 1.0 **** dT 13.319 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980607 1.0 **** dT 13.712 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980607 1.0 **** dT 16.277 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980610 1.0 **** dT 16.683 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980610 1.0 **** dT 19.343 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980613 1.0 **** dT 19.752 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980613 1.0 **** dT 22.305 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980616 1.0 **** dT 22.716 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980616 1.0 **** dT 25.263 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980619 1.0 **** dT 25.784 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980619 1.0 **** dT 28.320 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980622 1.0 **** dT 28.745 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980622 1.0 **** dT 31.282 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980625 1.0 **** dT 31.696 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980625 1.0 **** dT 34.352 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980628 1.0 **** dT 34.766 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980628 1.0 **** dT 37.307 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980631 1.0 **** dT 37.728 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980631 1.0 **** dT 40.360 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980634 1.0 **** dT 40.787 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980634 1.0 **** dT 43.329 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980637 1.0 **** dT 43.755 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980637 1.0 **** dT 46.292 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980640 1.0 **** dT 46.721 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980640 1.0 **** dT 49.345 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980643 1.0 **** dT 49.776 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980643 1.0 **** dT 52.299 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980646 1.0 **** dT 52.741 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980646 1.0 **** dT 55.368 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980649 1.0 **** dT 55.797 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980649 1.0 **** dT 58.323 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980652 1.0 **** dT 58.769 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980652 1.0 **** dT 61.384 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980655 1.0 **** dT 61.828 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980655 1.0 **** dT 64.331 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1739980658 1.0 **** dT 64.772 **** v2 vsl| 0 CLI - Rd ping **** v2 vsl| 0 CLI - Wr 200 19 PONG 1739980658 1.0 **** dT 65.608 ---- c1 HTTP rx timeout (fd:30 60.000s) **** dT 65.612 * top RESETTING after ../../../../bin/varnishtest/tests/d00007.vtc ** s1 Waiting for server (15/-1) ** v2 Wait **** v2 CLI TX|panic.show **** dT 65.663 *** v2 CLI RX 300 **** v2 CLI RX|Child has not panicked or panic has been cleared **** dT 65.664 *** v2 debug|Info: manager stopping child *** v2 debug|Debug: Stopping Child **** dT 65.676 **** v2 vsl| 1005 Begin b bereq 1004 pass **** v2 vsl| 1005 VCL_use b vcl1 **** v2 vsl| 1005 Timestamp b Start: 1739980600.417548 0.000000 0.000000 **** v2 vsl| 1005 BereqMethod b GET **** v2 vsl| 1005 BereqURL b / **** v2 vsl| 1005 BereqProtocol b HTTP/1.1 **** v2 vsl| 1005 BereqHeader b Host: 127.0.0.1 **** v2 vsl| 1005 BereqHeader b Probe: p2 **** v2 vsl| 1005 BereqHeader b X-Forwarded-For: 0.0.0.0 **** v2 vsl| 1005 BereqHeader b Via: 1.1 v2 (Varnish/trunk) **** v2 vsl| 1005 BereqHeader b Authority: 127.0.0.1 **** v2 vsl| 1005 BereqHeader b X-Varnish: 1005 **** v2 vsl| 1005 VCL_call b BACKEND_FETCH **** v2 vsl| 1005 VCL_return b fetch **** v2 vsl| 1005 Timestamp b Fetch: 1739980600.417561 0.000013 0.000013 **** v2 vsl| 1005 Timestamp b Connected: 1739980600.417610 0.000061 0.000048 **** v2 vsl| 1005 BackendOpen b 28 s1 127.0.0.1 45247 127.0.0.1 45838 connect **** v2 vsl| 1005 Timestamp b Bereq: 1739980600.417626 0.000077 0.000016 **** v2 vsl| 1005 FetchError b HTC eof (Unexpected end of input) **** v2 vsl| 1005 BackendClose b 28 s1 close RX_BAD **** v2 vsl| 1005 Timestamp b Beresp: 1739980659.479446 59.061898 59.061820 **** v2 vsl| 1005 Timestamp b Error: 1739980659.479452 59.061903 0.000005 **** v2 vsl| 1005 BerespProtocol b HTTP/1.1 **** v2 vsl| 1005 BerespStatus b 503 **** v2 vsl| 1005 BerespReason b Backend fetch failed **** v2 vsl| 1005 BerespHeader b Date: Wed, 19 Feb 2025 15:57:39 GMT **** v2 vsl| 1005 BerespHeader b Server: Varnish **** v2 vsl| 1005 VCL_call b BACKEND_ERROR **** v2 vsl| 1005 BerespHeader b Content-Type: text/html; charset=utf-8 **** v2 vsl| 1005 BerespHeader b Retry-After: 5 **** v2 vsl| 1005 VCL_return b deliver **** v2 vsl| 1005 Storage b malloc Transient **** v2 vsl| 1005 Length b 281 **** v2 vsl| 1005 BereqAcct b 140 0 140 0 0 0 **** v2 vsl| 1005 End b **** v2 vsl| 1004 Begin c req 1003 rxreq **** v2 vsl| 1004 Timestamp c Start: 1739980600.417170 0.000000 0.000000 **** v2 vsl| 1004 Timestamp c Req: 1739980600.417170 0.000000 0.000000 **** v2 vsl| 1004 VCL_use c vcl1 **** v2 vsl| 1004 ReqStart c 0.0.0.0 0 a0 **** v2 vsl| 1004 ReqMethod c GET **** v2 vsl| 1004 ReqURL c / **** v2 vsl| 1004 ReqProtocol c HTTP/1.1 **** v2 vsl| 1004 ReqHeader c Host: 127.0.0.1 **** v2 vsl| 1004 ReqHeader c Probe: p2 **** v2 vsl| 1004 ReqHeader c Connection: close **** v2 vsl| 1004 ReqHeader c X-Forwarded-For: 0.0.0.0 **** v2 vsl| 1004 ReqHeader c Via: 1.1 v2 (Varnish/trunk) **** v2 vsl| 1004 VCL_call c RECV **** v2 vsl| 1004 ReqHeader c Authority: 127.0.0.1 **** v2 vsl| 1004 VCL_return c pass **** v2 vsl| 1004 VCL_call c HASH **** v2 vsl| 1004 VCL_return c lookup **** v2 vsl| 1004 VCL_call c PASS **** v2 vsl| 1004 VCL_return c fetch **** v2 vsl| 1004 Link c bereq 1005 pass **** v2 vsl| 1004 Timestamp c Fetch: 1739980659.479610 59.062439 59.062439 **** v2 vsl| 1004 RespProtocol c HTTP/1.1 **** v2 vsl| 1004 RespStatus c 503 **** v2 vsl| 1004 RespReason c Backend fetch failed **** v2 vsl| 1004 RespHeader c Date: Wed, 19 Feb 2025 15:57:39 GMT **** v2 vsl| 1004 RespHeader c Server: Varnish **** v2 vsl| 1004 RespHeader c Content-Type: text/html; charset=utf-8 **** v2 vsl| 1004 RespHeader c Retry-After: 5 **** v2 vsl| 1004 RespHeader c X-Varnish: 1004 **** v2 vsl| 1004 RespHeader c Age: 0 **** v2 vsl| 1004 RespHeader c Via: 1.1 v2 (Varnish/trunk) **** v2 vsl| 1004 VCL_call c DELIVER **** v2 vsl| 1004 RespHeader c Authority: 127.0.0.1 **** v2 vsl| 1004 VCL_return c deliver **** v2 vsl| 1004 Timestamp c Process: 1739980659.479642 59.062471 0.000032 **** v2 vsl| 1004 Filters c **** v2 vsl| 1004 RespHeader c Content-Length: 281 **** v2 vsl| 1004 RespHeader c Connection: close **** v2 vsl| 1004 Timestamp c Resp: 1739980659.479694 59.062524 0.000052 **** v2 vsl| 1004 ReqAcct c 65 0 65 263 281 544 **** v2 vsl| 1004 End c **** v2 vsl| 1003 SessClose c REQ_CLOSE 59.063 **** v2 vsl| 1003 End c **** v2 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 65.754 **** v1 vsl| 1004 Begin b bereq 1003 fetch **** v1 vsl| 1004 VCL_use b vcl1 **** v1 vsl| 1004 Timestamp b Start: 1739980600.382892 0.000000 0.000000 **** v1 vsl| 1004 BereqMethod b GET **** v1 vsl| 1004 BereqURL b /2 **** v1 vsl| 1004 BereqProtocol b HTTP/1.1 **** v1 vsl| 1004 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1004 BereqHeader b User-Agent: c1 **** v1 vsl| 1004 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1004 BereqHeader b Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1004 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1004 BereqHeader b X-Varnish: 1004 **** v1 vsl| 1004 VCL_call b BACKEND_FETCH **** v1 vsl| 1004 VCL_return b fetch **** v1 vsl| 1004 Timestamp b Fetch: 1739980600.382926 0.000033 0.000033 **** v1 vsl| 1004 Timestamp b Connected: 1739980600.383070 0.000178 0.000144 **** v1 vsl| 1004 BackendOpen b 26 s1 127.0.0.1 42283 127.0.0.1 50518 connect **** v1 vsl| 1004 Timestamp b Bereq: 1739980600.383099 0.000207 0.000029 **** v1 vsl| 1004 FetchError b HTC eof (Unexpected end of input) **** v1 vsl| 1004 BackendClose b 26 s1 close RX_BAD **** v1 vsl| 1004 Timestamp b Beresp: 1739980659.547636 59.164743 59.164536 **** v1 vsl| 1004 Timestamp b Error: 1739980659.547639 59.164746 0.000003 **** v1 vsl| 1004 BerespProtocol b HTTP/1.1 **** v1 vsl| 1004 BerespStatus b 503 **** v1 vsl| 1004 BerespReason b Backend fetch failed **** v1 vsl| 1004 BerespHeader b Date: Wed, 19 Feb 2025 15:57:39 GMT **** v1 vsl| 1004 BerespHeader b Server: Varnish **** v1 vsl| 1004 VCL_call b BACKEND_ERROR **** v1 vsl| 1004 BerespHeader b Content-Type: text/html; charset=utf-8 **** v1 vsl| 1004 BerespHeader b Retry-After: 5 **** v1 vsl| 1004 VCL_return b deliver **** v1 vsl| 1004 Storage b malloc Transient **** v1 vsl| 1004 Length b 281 **** v1 vsl| 1004 BereqAcct b 149 0 149 0 0 0 **** v1 vsl| 1004 End b **** v1 vsl| 1003 Begin c req 1000 rxreq **** v1 vsl| 1003 Timestamp c Start: 1739980599.378125 0.000000 0.000000 **** v1 vsl| 1003 Timestamp c Req: 1739980599.378125 0.000000 0.000000 **** v1 vsl| 1003 VCL_use c vcl1 **** v1 vsl| 1003 ReqStart c 127.0.0.1 49514 a0 **** v1 vsl| 1003 ReqMethod c GET **** v1 vsl| 1003 ReqURL c /2 **** v1 vsl| 1003 ReqProtocol c HTTP/1.1 **** v1 vsl| 1003 ReqHeader c Host: 127.0.0.1 **** v1 vsl| 1003 ReqHeader c User-Agent: c1 **** v1 vsl| 1003 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1003 ReqHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1003 VCL_call c RECV **** v1 vsl| 1003 VCL_return c hash **** v1 vsl| 1003 VCL_call c HASH **** v1 vsl| 1003 VCL_return c lookup **** v1 vsl| 1003 VCL_call c MISS **** v1 vsl| 1003 VCL_return c fetch **** v1 vsl| 1003 Link c bereq 1004 fetch **** v1 vsl| 1003 Timestamp c Fetch: 1739980659.549561 60.171436 60.171436 **** v1 vsl| 1003 RespProtocol c HTTP/1.1 **** v1 vsl| 1003 RespStatus c 503 **** v1 vsl| 1003 RespReason c Backend fetch failed **** v1 vsl| 1003 RespHeader c Date: Wed, 19 Feb 2025 15:57:39 GMT **** v1 vsl| 1003 RespHeader c Server: Varnish **** v1 vsl| 1003 RespHeader c Content-Type: text/html; charset=utf-8 **** v1 vsl| 1003 RespHeader c Retry-After: 5 **** v1 vsl| 1003 RespHeader c X-Varnish: 1003 **** v1 vsl| 1003 RespHeader c Age: 0 **** v1 vsl| 1003 RespHeader c Via: 1.1 v1 (Varnish/trunk) **** v1 vsl| 1003 VCL_call c DELIVER **** v1 vsl| 1003 VCL_return c deliver **** v1 vsl| 1003 Timestamp c Process: 1739980659.549597 60.171472 0.000036 **** v1 vsl| 1003 Filters c **** v1 vsl| 1003 RespHeader c Content-Length: 281 **** v1 vsl| 1003 RespHeader c Connection: keep-alive **** v1 vsl| 1003 Timestamp c Resp: 1739980659.549629 60.171504 0.000032 **** v1 vsl| 1003 ReqAcct c 52 0 52 246 281 527 **** v1 vsl| 1003 End c **** dT 65.780 *** v2 debug|Info: Child (2687397) said Child dies *** v2 debug|Info: Child (2687397) ended *** v2 debug|Debug: Child cleanup complete *** v2 debug|Info: manager dies **** v2 STDOUT EOF ** v2 WAIT4 pid=2687384 status=0x0000 (user 0.261271 sys 0.058882) ** v1 Wait **** v1 CLI TX|panic.show **** dT 65.830 *** v1 CLI RX 300 **** v1 CLI RX|Child has not panicked or panic has been cleared **** dT 65.831 *** v1 debug|Info: manager stopping child *** v1 debug|Debug: Stopping Child **** dT 65.856 **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 65.935 *** v1 debug|Info: Child (2687450) said Child dies *** v1 debug|Info: Child (2687450) ended *** v1 debug|Debug: Child cleanup complete *** v1 debug|Info: manager dies **** v1 STDOUT EOF **** dT 65.959 ** v1 WAIT4 pid=2687437 status=0x0000 (user 0.256866 sys 0.038504) * top TEST ../../../../bin/varnishtest/tests/d00007.vtc FAILED # top TEST ../../../../bin/varnishtest/tests/d00007.vtc FAILED (65.961) exit=2 FAIL tests/d00007.vtc (exit status: 2)